Amazon Redshift: ユーザのSQL実行結果をログファイル(監査ログ)以外で確認する

Amazon Redshiftで良く使いそうな便利系SQL

#ビッグデータ

#Amazon Redshift

#AWS

しんや

2016.03.18

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

Amazon Redshiftには、SQLの実行ログを監査ログとしてS3に出力しておいてくれる機能があります。所定の操作を行なう事で以降は各種SQL実行内容もS3に出力してくれるようになるのですが、いざ問題が発覚し、『監査ログから内容を追おう』となった時に事態を想定すると『これは(担当者が)面倒くさいんじゃないかなぁ』と思った部分があったのでその辺について情報をまとめておこうと思います。

ユーザーアクティビティ監査ログを眺めてみるまでの流れ

まずはSQL実行ログ、これはRedshiftでは『ユーザーアクティビティログ』として定義されているものになります。詳細は以下のドキュメント等をご確認ください。

ユーザーアクティビティ監査ログの出力設定を行います。まずはクラスタ作成後、『Configure Audit Logging』を選択。

クラスタの監査ログ出力設定を有効化します。

程無くしてバケットが出来ました。ちなみにこの時点では有効となるのは『接続ログ』『ユーザーログ』の2つのみです。

SQL実行ログとなる『ユーザーアクティビティログ』出力を行なうには追加で設定を行います。クラスタに紐付くパラメータグループのenable user activity loggingという項目の値をtrueに変更し、保存(＆クラスタ再起動)します。

SQLを幾つか実行した後、しばらくすると(1時間程でしょうか)ログファイルが出力されてきます。試しにダウンロードして開いてみましょう。

中身はこんな感じです。1行で済んでいるSQLもあれば、改行含みのSQLもあります。この時点でJSON形式とかCSV形式になっていればこのファイル(群)をRedshiftに突っ込んで確認を...とかElasticSearchに突っ込んで確認を...とか色々思ったのですが、ファイルフォーマット的に、パッと対処するには厳しそうですね。(何らかのプログラムで解析し、JSONファイルに加工する等対処が必要そう)

で、このファイルを見て個人的にはこういう風に想像しました。

何か問題が起きる
『SQL監査ログ取ってあるから、この(S3に吐かれた)ログを使って情報探してみよう』
『どのテーブルだったか』とか『どういうSQLだったか』はあたりが付いている(調べるキーワードは何かしらある)
けど、正確な時間帯までは把握していない
ログを何かしら検索可能な機構に突っ込めれば全取り込み＆全文検索とかで探せるけど、この形じゃ厳しくね？
っていうかファイル数も1日だけで結構な数となる事が想定されるし、1個1個開いていって確認するのとか超面倒
ん〜、何か良い案無いかなぁ...

SQL実行ログはRedshiftのシステムテーブルにも記録されていた

良い案、ありました。

Redshiftでは以下のシステム系テーブルにそれぞれの実行内容に応じたSQL実行内容がデータとして格納されており、(アクセス権限を持つユーザーのみ可能となりますが)通常のテーブル同様にその内容を確認する事が出来ます。

上記テーブル一覧の４つめ、『SVL_STATEMENTTEXT』のドキュメントを確認してみます。このテーブルなら全てのSQL実行結果が格納されているので活用出来そうですね！

SVL_STATEMENTTEXT ビューを使用して、システムで実行されたすべての SQL コマンドの完全な記録を取得します。

SVL_STATEMENTTEXT ビューにはSTL_DDLTEXT、STL_QUERYTEXT、STL_UTILITYTEXT テーブルのすべての行の統合が含まれます。また、このビューには STL_QUERY テーブルの結合も含まれます。

早速内容を確認して見ましょう。上記実行ログ(のキャプチャ)で表示を確認している、改行文字を含んだSQLは以前書いたエントリ『Amazon Redshiftで良く使いそうな便利系SQLをまとめてみた』のSQL文の1つ、『テーブル分析結果を確認するその2』ですが、この中で利用されている関数部分の文字列を使って対象テーブルの内容を検索してみます。すると、該当する結果が出て来ました。SQLの実行時間も記録されていますので、この情報を以ってどの日のフォルダのどのファイルにSQL全文が記録されているか(注：SVL_STATEMENTTEXTテーブルはSQL実行部分を200文字毎に区切って管理しているため、SQLが200文字以上となる場合はその該当部分のレコードだけ表示される)を確認する事ができます。

このデータの日時情報をつかってファイルをピンポイントで見つける事が出来るので、余計な労力は割かなくて済みそうですね！

なお、ログファイル・当該テーブルの時間は全てタイムゾーン：UTCでの記録となります。下記SQLでは日本時間も併せて表示させていますので、日本時間でこの日時あたりだったから...みたいな"時間のアタリ"が付いているような場合、参考に出来る部分となるかと思います。

CONVERT_TIMEZONE 関数 - Amazon Redshift

# SELECT
  userid,
  xid,
  pid,
  TRIM(label) AS label,
  starttime,
  endtime,
  CONVERT_TIMEZONE('Asia/Tokyo', starttime) AS starttime_jst,
  CONVERT_TIMEZONE('Asia/Tokyo', endtime) AS endtime_jst,
  sequence,
  type,
  TRIM(text) AS sqltext
FROM
  SVL_STATEMENTTEXT
WHERE
  text like'%b.mbytes as double precision%'
ORDER BY
  starttime DESC;
  
 userid |  xid  |  pid  |  label  |         starttime          |          endtime           |       starttime_jst        |        endtime_jst         | sequence | type  |                                                                                                 sqltext                                                                                                 
--------+-------+-------+---------+----------------------------+----------------------------+----------------------------+----------------------------+----------+-------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    100 |  7940 | 13165 | default | 2016-03-17 05:52:46.969165 | 2016-03-17 05:52:47.488022 | 2016-03-17 14:52:46.969165 | 2016-03-17 14:52:47.488022 |        0 | QUERY | select\ntrim(pgdb.datname) as Database,\ntrim(pgn.nspname) as Schema,\ntrim(a.name) as Table,\nb.mbytes,\n(CAST(b.mbytes as double precision) / 1024) as gbytes,\n(CAST(b.mbytes as double precision) /
(1 rows)

#

気を付けなければいけないのは、ビューが参照しているシステム系テーブルは履歴保持期間が限られているため、状況に拠ってはデータベースにログが残っていない場合が考えられます。

必要に応じ、日付が変わって暫く経った後のバッチ処理で前日分のデータを個別に用意した同じデータ型構成の"自作退避用テーブル"に格納しておく等の対応が必要となるでしょう。

システムテーブルとビュー - Amazon Redshift

システムテーブルは自動または手動クラスターバックアップ（スナップショット）には含まれません。STL ログテーブルは、ログの使用状況と使用可能なディスク容量に応じて、およそ 2 ～ 5 日分のログ履歴のみを保持します。ログデータを保管するには、定期的に他のテーブルにコピーするか、Amazon S3 にアンロードする必要があります。

この道を用意しておく事で、何か問題があった場合も

何らかの問題発生
SQL実行ログから原因を探ろう
や、その前にデータベースにログ残してあるからそこをまず見てみよう
SQLによる情報の特定。
上記情報で不十分な場合は上記情報を元にS3監査ログ(ユーザーアクティビティログ)を確認
スムーズに原因特定ヽ(・∀・)ﾉｳﾏｰ

となるのでは無いかと思います。SQLログも日々処理が実行されていく度に蓄積されて行くので、一定期間経過した(自作退避用テーブルの)データについては削除しておくバッチ処理も仕込んでおくと良さ気かと。

まとめ

以上、Amazon RedshiftにおけるSQL監査ログの効率的な情報の探し方に関するご紹介でした。『問題発生タイミングが分かってればそんな大変でも無いんじゃない？』という気も書きながら思いましたが、得てして問題が発生した時はその辺の情報も分からなかったり、曖昧だったりするものです。そんな時に余計な労力を使わなくても済むよう、このエントリが幾らかお役に立てば幸いです。